The simplification conflicts with #14051

If you think this simplification is better, could you split up the PR so we can review the commits seperately?

@AndreasMadsen Oops. Hm, I don't have a strong opinion. As you've worked far more with async_hooks, I'd say it's your call.

as fatalError has nothing to do with async_hooks.

A bit off topic but your comment made me think we might at some point want to create long stacks for our exceptions, probably just for test/, but maybe for all?

What are "long stacks"?

Oops. Hm, I don't have a strong opinion. As you've worked far more with async_hooks, I'd say it's your call.

I have now confirmed that the issue in #14051 has nothing to do with my changes. So I think I prefer my approach in #14051. This is how it is done in the async_hooks C++, I think it makes sense to use the same approach in async_hooks JS.

What are "long stacks"?

async-context stacktraces. But that discussion should be in a separate thread.

async_hooks: move restoreTmpHooks call to init

It should be possible to provoke an error in the previous implementation, by:

1. listen to init
2. start an native handle, fs.open() or similar should do.
3. create a new init listener in the current init listener. This should not emit by fs.open() is step (not a bug).
4. start an native handle, fs.open() or similar should do.
5. If I'm right, the second init hook (3.) will not fire (bug). This fix should cause the second init hook to be fired.

[refack: fixed typo]

@AndreasMadsen Here's a test for what I believe you're talking about:

'use strict';

const print = process._rawDebug;
const init_calls = { hook1: 0, hook2: 0 };
let hook2_enabled = true;

process.on('exit', () => {
  require('assert').strictEqual(init_calls.hook1, init_calls.hook2);
});

const hook1 = require('async_hooks').createHook({
  init(id, type) {
    init_calls.hook1++;
    print('hook1 init:', id, type);
    if (hook2_enabled) {
      hook2_enabled = false;
      hook2.enable();
      require('crypto').randomBytes(1024, () => {});
    }
  }
});

const hook2 = require('async_hooks').createHook({
  init(id, type) {
    init_calls.hook2++;
    print('hook2 init:', id, type);
  },
});

setImmediate(() => {
  hook1.enable();
  hook2.enable();
  require('fs').open('/dev/null', 'r', (er, fd) => {});
});

This shows that init still runs for both hook1 and hook2 for both events. This test passes for v8.1.3, but fails with the following when applying this patch:

assert.js:60
  throw new errors.AssertionError({
  ^

AssertionError [ERR_ASSERTION]: 2 === 1
    at process.on (/tmp/async-fs-init.js:8:21)
    at emitOne (events.js:115:13)
    at process.emit (events.js:210:7)

@trevnorris there is a comment in the code that says:

// The set of callbacks for a hook should be the same regardless of whether
// enable()/disable() are run during their execution.

If I understand that comment correctly, it says that hook2.enable(); should be delayed to after the current init hook(s) are done executing. Thus, init_calls.hook1 !== init_calls.hook2 is the expected behavior.

@AndreasMadsen Here's a more generalized test for discussion:

'use strict';

const { createHook } = require('async_hooks');
const { randomBytes } = require('crypto');
const print = process._rawDebug;
const hooks_list = [];
const start_enabled = process.argv[2] === '--start-enabled';
let cntr = -1;

for (let i = 0; i < 2; i++) {
  hooks_list.push(createHook({
    init(id, type) { print(`hook${i} init`); },
  }));
  if (start_enabled) hooks_list[hooks_list.length - 1].enable();
}

const hook = createHook({
  init(id, type) {
    print('hook init:', id, type);
    if (++cntr < hooks_list.length) {
      if (start_enabled)
        hooks_list[cntr].disable();
      else
        hooks_list[cntr].enable();
      randomBytes(1, () => {});
    }
  }
}).enable();

randomBytes(1, () => {});

First running without --start-enabled:

v8.1.3                            pr-1405
------                            -------
hook init: 2 RANDOMBYTESREQUEST   hook init: 2 RANDOMBYTESREQUEST
hook init: 3 RANDOMBYTESREQUEST   hook init: 3 RANDOMBYTESREQUEST
hook init: 4 RANDOMBYTESREQUEST   hook init: 4 RANDOMBYTESREQUEST
                                  hook0 init
                                  hook1 init
                                  hook0 init
                                  hook1 init

Now running with --start-enabled:

v8.1.3                            pr-1405
------                            -------
hook0 init                        hook0 init
hook1 init                        hook1 init
hook init: 2 RANDOMBYTESREQUEST   hook init: 2 RANDOMBYTESREQUEST
hook0 init                        hook0 init
hook1 init                        hook1 init
hook init: 3 RANDOMBYTESREQUEST   hook init: 3 RANDOMBYTESREQUEST
hook0 init                        hook0 init
hook1 init                        hook1 init
hook init: 4 RANDOMBYTESREQUEST   hook init: 4 RANDOMBYTESREQUEST

First thing to address is that I wouldn't expect the output for running with --start-enabled to be the same between v8.1.3 and this patch. Similar to how it's different with running without --start-enabled. Instead I would have expected the output of this patch with --start-enabled to be something like:

hook0 init
hook1 init
hook init: 2 RANDOMBYTESREQUEST
hook1 init
hook init: 3 RANDOMBYTESREQUEST
hook init: 4 RANDOMBYTESREQUEST

As we can see from the first results table there's a strange timing issue. Namely I would have expected the output for running without --start-enabled to look like:

hook init: 2 RANDOMBYTESREQUEST
hook init: 3 RANDOMBYTESREQUEST
hook0 init
hook init: 4 RANDOMBYTESREQUEST
hook0 init
hook1 init

For simplicity I would interpret that comment to mean the set of callbacks from the entry point of init(), and recursive calls to init() will always call the same set of hook callbacks as its parent. Honestly the idea of recursive init() calls didn't cross my mind when writing that comment, but IMO having each recursive call to init() always call the same set of callbacks that were enabled/disabled at the time of the calling of its parent is the easiest to code and to reason about.

First of all: I really struggle to understand what you are arguing for. Are you against this PR? If this is the case, try logging when storeActiveHooks and restoreTmpHooks are called, then the bug is quite obvious.

without --start-enabled:

hook init: 2 RANDOMBYTESREQUEST
storeActiveHooks
hook init: 3 RANDOMBYTESREQUEST
hook init: 4 RANDOMBYTESREQUEST

You will immediately see that when init is called from native, restoreTmpHooks is never called. This means that we are stuck in the temp state, that is a bug.

Assuming you don't think this PR is wrong but something is odd about the output:

In the case without --start-enabled we see hook0 init and hook1 init, this is odd. As no hooks should be enabled during the execution of hook (only after all initial init hooks should they be enabled).

The reason for this is a bug, is the use of a single flag for processing_hook. A single flag is not enough when dealing with nested init calls. Let's consider the simpler case where hooks_list.length === 1.

enable
hook init: 2 RANDOMBYTESREQUEST
enable
storeActiveHooks
hook init: 3 RANDOMBYTESREQUEST
restoreTmpHooks
hook0 init

On the surface, this might look fine, but what actually happens is that restoreTmpHooks is called from the inner emitInitN hooks (caused by randomBytes in init). This means in the loop for the outer emitInitN hooks (caused by the first randomBytes) the temp_arrays now becomes the active_hooks_array. Since active_hooks_array.length is accessed dynamically, the for-loop now sees a longer active_hooks_array and continues to execute the hooks.

To put it differently, active_hooks_array.length should never change but it does because restoreTmpHooks is called too early.

The solution as I see it, is to only let the outer emitInitN call restoreTmpHooks. This can be done by using a counter instead of a flag. With such a fix, the results are now:

without --start-enabled.

hook init: 2 RANDOMBYTESREQUEST
hook init: 3 RANDOMBYTESREQUEST
hook init: 4 RANDOMBYTESREQUEST

with --start-enabled.

hook0 init
hook1 init
hook init: 2 RANDOMBYTESREQUEST
hook0 init
hook1 init
hook init: 3 RANDOMBYTESREQUEST
hook0 init
hook1 init
hook init: 4 RANDOMBYTESREQUEST

I don't know why you would expect the number of called hooks to change in the "with --start-enabled" case. This behavior seems correct to me since the hooks array should never change during processing.

I will create a pull request that depends on this PR and contains the additional fix I'm suggesting.

PR #14143 contains the suggested fix.

@BridgeAR Having spend some time debugging @trevnorris's issue I think this test better highlights the issue this PR solves:

'use strict';

const common = require('../common');
const assert = require('assert');
const async_hooks = require('async_hooks');
const crypto = require('crypto');

const nestedHook = async_hooks.createHook({
  init: common.mustCall()
});

const rootHook = async_hooks.createHook({
  init: common.mustCall(function (id, type) {
    nestedHook.enable();
  }, 2)
}).enable();

crypto.randomBytes(1, common.mustCall(function () {
  crypto.randomBytes(1, common.mustCall());
}));

@AndreasMadsen thanks a lot for the test. As you opened the follow up PR and did pretty much all work here, I could also close this one and you add the test to your PR?

Thanks a lot for the test. As you opened the follow up PR and did pretty much all work here, I could also close this one and you add the test to your PR?

You have my permission to just copy and paste the test case I wrote. If @trevnorris thinks we should land this and #14143 together for it to make sense, then I will just rebase #14143 again.

Rebased (I changed the commit message a bit) and incorporated.

CI: https://ci.nodejs.org/job/node-test-pull-request/9057/

landed in 8a83035